Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Trace IDs and metadata to log lines #648

Merged
merged 10 commits into from
Jun 18, 2024

Conversation

shulin-sq
Copy link
Contributor

@shulin-sq shulin-sq commented Jun 7, 2024

What type of PR is this?
feature (?)

Which issue does this PR fix:
#603

What does this PR do / Why do we need it:
This PR adds the ability to track trace id and metadata to all log lines. It also changes the log interface so that in most cases, developers are forced to add a context instance to the log line.

The previous PR was here: #624 but was based on an older release version. I decided to recreate the branch on top of main.

This PR also addresses some of the comments brought up in the previous PR

Additional resources:

Testing done on this change:

ran

go test ./...

and also ran a built version in my test EKS cluster.

Automation added to e2e:

no

Will this PR introduce any new dependencies?:

no

Will this break upgrades or downgrades. Has updating a running cluster been tested?:

no, will not break since it's a change to do with the logging interface

Does this PR introduce any user-facing change?:

no

How to use:

For all Reconcile I have added something like this at the beginning of the method

	ctx = gwlog.StartReconcileTrace(ctx, c.log, "iamauthpolicy", req.Name)
	defer func() {
		gwlog.EndReconcileTrace(ctx, c.log)
	}()

this should produce a log line like so:

{"level":"info","ts":"2024-06-07T06:27:53.311Z","logger":"controller.iam-auth-policy","caller":"gwlog/metadata.go:79","msg":"[ACTION_RECONCILE_START]","type":"iamauthpolicy","name":"foo-test","trace_id":"3442054d-0f06-46ac-84bb-7e0112cfa60d"}
{"level":"info","ts":"2024-06-07T06:27:53.311Z","logger":"controller.iam-auth-policy","caller":"controllers/iamauthpolicy_controller.go:92","msg":"reconcile IAM policy","req":"lattice/foo-test","targetRef":{"group":"gateway.networking.k8s.io","kind":"HTTPRoute","name":"foo-test-all
","namespace":"foo-test"},"trace_id":"3442054d-0f06-46ac-84bb-7e0112cfa60d"}
{"level":"info","ts":"2024-06-07T06:27:53.333Z","logger":"controller.iam-auth-policy","caller":"controllers/iamauthpolicy_controller.go:110","msg":"reconciled IAM policy","req":"lattice/foo-test","targetRef":{"group":"gateway.networking.k8s.io","kind":"HTTPRoute","name":"foo-test-a
ll","namespace":"foo-test"},"isDeleted":false,"trace_id":"3442054d-0f06-46ac-84bb-7e0112cfa60d"}
{"level":"info","ts":"2024-06-07T06:27:53.333Z","logger":"controller.iam-auth-policy","caller":"gwlog/metadata.go:85","msg":"[ACTION_RECONCILE_END]","type":"iamauthpolicy","name":"foo-test","trace_id":"3442054d-0f06-46ac-84bb-7e0112cfa60d"}

Something to do next, but not as part of this PR as I do not want to conflict with future changes that want to add more log lines is that for errors you can add why a reconcile failed as part of the metadata.

for example in TargetGroupPolicyController you can change this logic to

	_, err = c.ph.ValidateAndUpdateCondition(ctx, tgPolicy)
	if err != nil {
		gwlog.AddMetadata(ctx, "failed_reason", err.Error())
		return ctrl.Result{}, err
	}

and then the failed_reason will show up in the [ACTION_RECONCILE_END] message.

You can still keep using the original logger as it's exposed as InnerLogger in TracedLogger.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

@erikfuller
Copy link
Contributor

you can see that trace 3442054d-0f06-46ac-84bb-7e0112cfa60d is separate from 3442054d-0f06-46ac-84bb-7e0112cfa60d

Just checking this is what you meant as these ids are the same?

@shulin-sq
Copy link
Contributor Author

shulin-sq commented Jun 10, 2024

@erikfuller oops you're correct. I've updated my description.

I tried looking through my logs to see if I Can find a better example but I have very low traffic in my dev env so I don't see a lot of overlapping actions. However I can confirm that the uuid is correctly generated as unique per action

{"level":"info","ts":"2024-06-10T16:36:21.798Z","logger":"controller.gateway","caller":"gwlog/metadata.go:85","msg":"[ACTION_RECONCILE_END]","type":
"gateway","name":"snarl-10-isglf3puxg","trace_id":"b952b248-bf75-49d0-8984-311374ad9012"}
{"level":"info","ts":"2024-06-10T16:36:21.801Z","logger":"controller.gateway","caller":"gwlog/metadata.go:79","msg":"[ACTION_RECONCILE_START]","type
":"gateway","name":"shulilntest","trace_id":"287c9b37-faaf-4429-8b8c-a85dbb778de3"}

Copy link
Contributor

@erikfuller erikfuller left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the PR @shulin-sq, being able to better correlate logs will really help with debugging. I have a few comments and requests, please just let me know if anything is unclear and feel free to push back if you think I've got something wrong.

Note there are also a few conflicts after merging in the tls-passthrough PR, please resolve those as well. There shouldn't be any further PRs coming through before this one so this should be a one-time conflict resolution.

pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Show resolved Hide resolved
pkg/controllers/route_controller.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Show resolved Hide resolved
pkg/utils/gwlog/gwlog.go Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/metadata_test.go Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/gwlog.go Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
pkg/utils/gwlog/metadata_test.go Show resolved Hide resolved
test/go.mod Outdated
Comment on lines 3 to 6
go 1.21

toolchain go1.22.1

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll remove this, this is something that got added by my IDE

pkg/utils/gwlog/metadata.go Outdated Show resolved Hide resolved
@erikfuller erikfuller assigned shulin-sq and unassigned shulin-sq Jun 12, 2024
@shulin-sq shulin-sq force-pushed the shulin/traced-logging-v2 branch from a7c6e7d to 12e6131 Compare June 13, 2024 11:10
@shulin-sq shulin-sq force-pushed the shulin/traced-logging-v2 branch from 728309a to 4a65bf8 Compare June 13, 2024 11:51
@shulin-sq shulin-sq requested a review from erikfuller June 13, 2024 14:58
@shulin-sq
Copy link
Contributor Author

@erikfuller I updated the PR, please let me know if there are further requested modifications

Copy link
Contributor

@erikfuller erikfuller left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks again for putting this together. Look forward to seeing this in action!

@shulin-sq shulin-sq force-pushed the shulin/traced-logging-v2 branch from e283318 to 0de1bcb Compare June 18, 2024 11:57
@shulin-sq shulin-sq force-pushed the shulin/traced-logging-v2 branch from 0de1bcb to 690e17f Compare June 18, 2024 13:18
@erikfuller erikfuller merged commit 293531f into aws:main Jun 18, 2024
2 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants